Async Hooksを使ってリクエストごとに一意なIDをログに出力する

#Node.js

#nestjs

Ryosuke IGARASHI

2018.12.29

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

少し長い前置き

APIサーバのログでトレーサビリティを向上させるために、リクエストごとに一意なIDを出力するのはよく使われるテクニックです。例えば、Ruby on Railsは標準でログにリクエストIDが出力されるようになっています。かなり大雑把に言ってしまえば、リクエストごとにスレッドが割り当てられる実行環境であれば、スレッド単位でリクエストIDを保持すれば実現できると思います。JavaだとMDCとかを使うのかな？

一方で、Node.jsの場合はシングルスレッドのイベントループでリクエストを処理しますから、前述した方法は使えません。そこで、多くのNode.jsのFrameworkでは、実行コンテキストを関数の引数で引き回しています。私が以前、Koa.jsでAPIサーバを実装したときも、実行コンテキストにloggerインスタンスをセットしてリクエストIDを出力していました。この方法では、ログを出したいところまで実行コンテキスト（の中のloggerインスタンス）を引き回す必要があり冗長なコードを強いられていました。

しかし、最近興味を持ってさわっているTypeScriptベースのnestというFrameworkでもその方法を試そうとしてみたのですが、nestは独自のDIコンテナとアスペクト指向プログラミングを組み合わせた美しい設計になっており、実行コンテキストは隠蔽されていました。一応、リクエストのHandler関数やInterceptor（nestの用語）では実行コンテキストを見ることはできるのですが、そこから引き回したりするのはこの美しい設計を穢してしまうことになるので許容できません。何か他の方法がないかと三日三晩探した結果、Async Hooksを使うテクニックを見つけました。

Async Hooksは現在 Stability: 1 - Experimental として実験的に導入されている段階です。これを使ってリクエストのコンテキストを保持するexpressのミドルウェア（express-http-context）などもあります。nestもexpressベースで作られているため、expressのミドルウェアを使えるのですが、express-http-contextは動作しませんでした。詳しい原因までは追ってないのですが、DIコンテナでインスタンスが作られているためかと思います。しかし、nestでAsync Hooksを使った実装例（例1, 例2, など)もありますし、nestの作者もAsync HooksがStableになればコア機能として取り入れる意志があるようなので、希望はありそうです。

環境

$ node -v
v10.8.0

Async Hooksとは

Async Hooksの話しに戻ります。

Async Hooksとは、非同期処理のライフサイクルにフックを仕掛ける機能のことです。非同期処理が実行されると、非同期リソースというリソースが生成されます。ライフサイクルはその非同期リソースのイベントで、init（初期化時）, before（コールバック実行前）, after（コールバック実行後）, destroy（破棄後）の4つがあります。この4つのイベントで任意のコードを実行することができます。また非同期リソースには、自身のIDと、呼び出し元の非同期リソースのIDがセットされています。また、本記事では取り扱いませんが、Embedder APIを用いることで、ライフサイクルイベントを任意のタイミングで実行することもできます。

動作を把握するため、リファレンスのサンプルコードに少しだけ手を加えて動かしてみます。

index.js

const fs = require('fs')
const async_hooks = require('async_hooks')

async_hooks.createHook({
  init(asyncId, type, triggerAsyncId) {
    const eid = async_hooks.executionAsyncId();
    fs.writeSync(
      1, `${type}(${asyncId}): trigger: ${triggerAsyncId} execution: ${eid}\n`);
  },
  before(asyncId) {
    const eid = async_hooks.executionAsyncId();
    fs.writeSync(
      1, `Before ${asyncId} execution: ${eid}\n`);
    },
  after(asyncId) {
    const eid = async_hooks.executionAsyncId();
    fs.writeSync(
      1, `After ${asyncId} execution: ${eid}\n`);
  },
  destroy(asyncId) {
    const eid = async_hooks.executionAsyncId();
    fs.writeSync(
      1, `Destroy ${asyncId} execution: ${eid}\n`);
  }
}).enable();

fs.writeSync(
  1, `trigger: ${async_hooks.triggerAsyncId()} execution: ${async_hooks.executionAsyncId()}\n`);

require('net').createServer((conn) => {}).listen(8080);

async_hooks.createHookの部分でライフサイクルイベントを設定しています。この例ではログを出すだけです。ちなみにconsole.logではなくfs.writeSyncを使っているのは、console.logが非同期処理であるためinitイベントが無限ループしてしまうためです。

実行ログ

$ node index.js
trigger: 0 execution: 1
TCPSERVERWRAP(5): trigger: 1 execution: 1
TickObject(6): trigger: 5 execution: 1
Before 6 execution: 6
After 6 execution: 6

# ここで別のターミナルから `curl -XGET localhost:8080` を実行
TCPWRAP(7): trigger: 5 execution: 0
Before 5 execution: 0
After 5 execution: 0
Destroy 6 execution: 0
Before 7 execution: 0
TickObject(8): trigger: 7 execution: 7
TickObject(9): trigger: 7 execution: 7
After 7 execution: 0
Before 8 execution: 8
After 8 execution: 8
Before 9 execution: 9
After 9 execution: 9
Destroy 8 execution: 0
Destroy 9 execution: 0

最初の非同期リソースのIdは1でtriggerが0ですから、この場合はNode.jsの実行環境から生成されたことを意味します。そしてこの非同期リソースから、TCPSERVERWRAP(5)が作られ、TCPSERVERWRAP(5)からTickObject(6)が作られたことがtriggerから分かります。リクエストを受け取ったときも同様に、TCPSERVERWRAP(5)からTCPWRAP(7)を生成し、リソースが連鎖的に生成され、処理が終わると削除されています。

実装例

次に、ログ出力に関する具体的な実装をしてみます。node-request-contextの実装に倣って、koaでコンテキスト引き回さずにログにリクエストごとに一意なリクエストIDを出力するようにします。

package.json

{
  "dependencies": {
    "koa": "2.6.2",
    "uuid": "3.3.2"
  }
}

namespace.js

const asyncHooks = require('async_hooks')

class Namespace {
  constructor() {
    this.context = {}
  }

  async run(fn) {
    const eid = asyncHooks.executionAsyncId()
    this.context[eid] = {}
    await fn()
  }

  set(key, val) {
    const eid = asyncHooks.executionAsyncId()
    this.context[eid][key] = val
  }

  get(key) {
    const eid = asyncHooks.executionAsyncId()
    return this.context[eid][key]
  }
}

module.exports = Namespace

index.js

'use strict'
const asyncHooks = require('async_hooks')
const Namespace = require('./namespace')
global.namespace = new Namespace()
createHooks(global.namespace)

const uuidv4 = require('uuid/v4')
const Koa = require('koa')
const app = new Koa()

app.use(async (ctx, next) => {
  await namespace.run(async () => {
    namespace.set('requestId', uuidv4())
    await next()
  })
})
app.use(async (ctx, next) => {
  logger('function 1')
  await new Promise(resolve => {
    setTimeout(resolve, 3000)
  })
  await next()
})
app.use(async ctx => {
  logger('function 2')
  ctx.body = 'Hello World'
})
app.listen(3000)

function createHooks(namespace) {
  asyncHooks
    .createHook({
      init(asyncId, type, triggerId, resource) {
        if (namespace.context[triggerId]) {
          namespace.context[asyncId] = namespace.context[triggerId]
        }
      },
      destroy(asyncId) {
        delete namespace.context[asyncId]
      }
    })
    .enable()
}

function logger(msg) {
  console.log(msg, { requestId: global.namespace.get('requestId') })
}

ポイントが2つあります。

createHooksでasyncHooksを設定します。initのイベントフックで、新しい非同期リソースが生成されたときに、トリガーIDのコンテキストを、新しい非同期リソースのIDのコンテキストにコピーしています。これにより、次々と新しい非同期処理に呼び出し元のコンテキストが引き継がれます。要するにコンテキストの引き回しが表舞台から裏舞台に変わっただけです。
最初のapp.useで、以降のnextをnamespace.runの中で実行するようにします。これにより、リクエスト単位でコンテキストが固定されます。

リクエストごとに一意であるかを確認するために、複数のクライアントからほぼ同時にリクエストを送信しました。以下のログから、リクエストごとにrequestIdが一意であることが分かります。

$ node index.js
function 1 { requestId: 'bde8d86a-9c98-44b1-a691-65d0d9cb8d63' }
function 1 { requestId: '13b3be9e-4438-4827-978b-1f1abf108023' }
function 2 { requestId: 'bde8d86a-9c98-44b1-a691-65d0d9cb8d63' }
function 2 { requestId: '13b3be9e-4438-4827-978b-1f1abf108023' }

実装例ではAsync Hooksを使って目的の処理が実現できることが確認できました。ですが、この実装はglobalオブジェクトを使用していること（ここでは必要なかったですが、任意のLoggerで参照することを想定しglobalオブジェクトにしました）や、メモリやパフォーマンスをトレードオフしているなど、実用するには問題があると思います。

こちらのissueでは、nestの作者を含め実装方法の議論がなされているので、もっと良い実装がされるのではないかと思います。まだ詳しく読めてないので、読んでみたいと思います。